cli: also log applier debug messages to debug log file by 3u13r · Pull Request #3457 · edgelesssys/constellation

3u13r · 2024-10-24T10:14:10Z

Context

Currenlty, when the coordinator is not reachable, the last log line is

{"time":"2024-10-18T11:59:38.778068783+02:00","level":"DEBUG","source":{"function":"github.com/edgelesssys/constellation/v2/cli/internal/cmd.(*applyCmd).runInit","file":"cli/internal/cmd/applyinit.go","line":38},"msg":"Running init RPC"}

<nothing else here, next line only if init is successful>

{"time":"2024-10-18T12:01:08.364242086+02:00","level":"DEBUG","source":{"function":"github.com/edgelesssys/constellation/v2/cli/internal/cmd.(*applyCmd).runInit","file":"cli/internal/cmd/applyinit.go","line":77},"msg":"Initialization request successful"}

Proposed change(s)

Use existing debugLogger, that logs both to a file and to stderr, in the applier that makes the init call to the coordinator.

Now the logs also containt he following messages each time the CLI tries to init (those were previously only available directly in the cli output but not in the constellation-debug.log file)

{"time":"2024-10-24T11:57:16.602504601+02:00","level":"DEBUG","source":{"function":"github.com/edgelesssys/constellation/v2/cli/internal/cmd.(*applyCmd).runInit","file":"cli/internal/cmd/applyinit.go","line":38},"msg":"Running init RPC"}
{"time":"2024-10-24T11:57:16.602531232+02:00","level":"DEBUG","source":{"function":"github.com/edgelesssys/constellation/v2/internal/constellation.(*Applier).GenerateMasterSecret","file":"internal/constellation/apply.go","line":125},"msg":"Generating master secret"}
{"time":"2024-10-24T11:57:16.602556592+02:00","level":"DEBUG","source":{"function":"github.com/edgelesssys/constellation/v2/internal/constellation.(*Applier).GenerateMasterSecret","file":"internal/constellation/apply.go","line":138},"msg":"Generated master secret key and salt values"}
{"time":"2024-10-24T11:57:16.602652653+02:00","level":"DEBUG","source":{"function":"github.com/edgelesssys/constellation/v2/internal/constellation.(*Applier).GenerateMeasurementSalt","file":"internal/constellation/apply.go","line":144},"msg":"Generating measurement salt"}
{"time":"2024-10-24T11:57:16.602675503+02:00","level":"DEBUG","source":{"function":"github.com/edgelesssys/constellation/v2/internal/constellation.(*Applier).GenerateMeasurementSalt","file":"internal/constellation/apply.go","line":149},"msg":"Generated measurement salt"}
{"time":"2024-10-24T11:57:16.602700083+02:00","level":"DEBUG","source":{"function":"github.com/edgelesssys/constellation/v2/internal/constellation.(*Applier).Init","file":"internal/constellation/applyinit.go","line":93},"msg":"Initialization call","endpoint":"34.117.169.242:9000"}
{"time":"2024-10-24T11:57:16.602804065+02:00","level":"DEBUG","source":{"function":"github.com/edgelesssys/constellation/v2/internal/constellation.(*initDoer).Do","file":"internal/constellation/applyinit.go","line":191},"msg":"Created protoClient"}
{"time":"2024-10-24T11:57:16.602855575+02:00","level":"DEBUG","source":{"function":"github.com/edgelesssys/constellation/v2/internal/grpc/grpclog.LogStateChangesUntilReady.func1","file":"internal/grpc/grpclog/grpclog.go","line":34},"msg":"Connection state started as \"IDLE\""}
{"time":"2024-10-24T11:57:16.602976596+02:00","level":"DEBUG","source":{"function":"github.com/edgelesssys/constellation/v2/internal/grpc/grpclog.LogStateChangesUntilReady.func1","file":"internal/grpc/grpclog/grpclog.go","line":36},"msg":"Connection state changed to \"IDLE\""}
{"time":"2024-10-24T11:57:16.619469197+02:00","level":"DEBUG","source":{"function":"github.com/edgelesssys/constellation/v2/internal/grpc/grpclog.LogStateChangesUntilReady.func1","file":"internal/grpc/grpclog/grpclog.go","line":36},"msg":"Connection state changed to \"CONNECTING\""}
{"time":"2024-10-24T11:57:16.619528677+02:00","level":"DEBUG","source":{"function":"github.com/edgelesssys/constellation/v2/internal/grpc/grpclog.LogStateChangesUntilReady.func1","file":"internal/grpc/grpclog/grpclog.go","line":42},"msg":"Connection state ended with \"TRANSIENT_FAILURE\""}
{"time":"2024-10-24T11:57:16.619659429+02:00","level":"DEBUG","source":{"function":"github.com/edgelesssys/constellation/v2/internal/constellation.(*Applier).Init.func1","file":"internal/constellation/applyinit.go","line":88},"msg":"Encountered error (retriable: true): \"init call: rpc error: code = Unavailable desc = connection error: desc = \\\"transport: authentication handshake failed: EOF\\\"\""}
{"time":"2024-10-24T11:57:46.606037431+02:00","level":"DEBUG","source":{"function":"github.com/edgelesssys/constellation/v2/internal/constellation.(*initDoer).Do","file":"internal/constellation/applyinit.go","line":191},"msg":"Created protoClient"}
{"time":"2024-10-24T11:57:46.606093582+02:00","level":"DEBUG","source":{"function":"github.com/edgelesssys/constellation/v2/internal/grpc/grpclog.LogStateChangesUntilReady.func1","file":"internal/grpc/grpclog/grpclog.go","line":34},"msg":"Connection state started as \"IDLE\""}
{"time":"2024-10-24T11:57:46.606321074+02:00","level":"DEBUG","source":{"function":"github.com/edgelesssys/constellation/v2/internal/grpc/grpclog.LogStateChangesUntilReady.func1","file":"internal/grpc/grpclog/grpclog.go","line":36},"msg":"Connection state changed to \"IDLE\""}
{"time":"2024-10-24T11:57:46.623866876+02:00","level":"DEBUG","source":{"function":"github.com/edgelesssys/constellation/v2/internal/grpc/grpclog.LogStateChangesUntilReady.func1","file":"internal/grpc/grpclog/grpclog.go","line":36},"msg":"Connection state changed to \"CONNECTING\""}
{"time":"2024-10-24T11:57:46.623954387+02:00","level":"DEBUG","source":{"function":"github.com/edgelesssys/constellation/v2/internal/grpc/grpclog.LogStateChangesUntilReady.func1","file":"internal/grpc/grpclog/grpclog.go","line":42},"msg":"Connection state ended with \"TRANSIENT_FAILURE\""}

Checklist

Add labels (e.g., for changelog category)
Link to Milestone

netlify · 2024-10-24T10:14:38Z

✅ Deploy Preview for constellation-docs canceled.

Name	Link
🔨 Latest commit	`a7b2a2c`
🔍 Latest deploy log	https://app.netlify.com/sites/constellation-docs/deploys/671a32e751804400080c5d3f

thomasten · 2024-10-24T11:17:11Z

cli/internal/cmd/apply.go


 	fileHandler := file.NewHandler(afero.NewOsFs())
-	logger, err := newDebugFileLogger(cmd, fileHandler)
+	debugLogger, err := newDebugFileLogger(cmd, fileHandler)


I don't understand why we have two loggers in this func. Should we just log everything with this logger?

The other logger log is now only used in the warnLogger, which in turn is only used https://github.com/edgelesssys/constellation/blob/euler/cli/extend-file-debug-log/cli/internal/cmd/applyinit.go#L33. I think in general terms, we want to print warning non-structured, so not with slog.

The simplest solution would be to use the debugLogger instead of log when creating the warnLogger and in the warnLogger's implementation we debug log additionally when calling Warn.
EDIT: this would print the warning twice to the user, once structured and once unstructured when debug is enabled, which is fine in my opinion.

The current state (last commit) is a proposal for this version.

I agree that printing the warning as structured debug log again is fine.

github-actions · 2024-10-24T12:05:43Z

Coverage report

Package	Old	New	Trend
cli/internal/cmd	57.90%	57.90%	↔️

thomasten

LGTM

* cli: also log applier debug messages to debug log file * cli: use debug logger instead of cliLogger

cli: also log applier debug messages to debug log file

03fd049

3u13r added the no changelog Change won't be listed in release changelog label Oct 24, 2024

3u13r added this to the v2.20.0 milestone Oct 24, 2024

3u13r requested review from daniel-weisse, miampf and thomasten October 24, 2024 10:14

daniel-weisse approved these changes Oct 24, 2024

View reviewed changes

thomasten reviewed Oct 24, 2024

View reviewed changes

cli: use debug logger instead of cliLogger

a7b2a2c

3u13r requested a review from thomasten October 24, 2024 11:53

miampf approved these changes Oct 24, 2024

View reviewed changes

thomasten approved these changes Oct 24, 2024

View reviewed changes

3u13r requested a review from daniel-weisse October 24, 2024 12:29

daniel-weisse approved these changes Oct 24, 2024

View reviewed changes

3u13r merged commit 2cd5b05 into main Oct 24, 2024

3u13r deleted the euler/cli/extend-file-debug-log branch October 24, 2024 13:00

3u13r added the needs backport This PR needs to be backported to a previous release label Oct 24, 2024

elchead pushed a commit that referenced this pull request Nov 5, 2024

cli: also log applier debug messages to debug log file (#3457)

33f1a91

* cli: also log applier debug messages to debug log file * cli: use debug logger instead of cliLogger

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Comments

cli: also log applier debug messages to debug log file#3457

cli: also log applier debug messages to debug log file#3457
3u13r merged 2 commits intomainfrom
euler/cli/extend-file-debug-log

3u13r commented Oct 24, 2024

Uh oh!

netlify bot commented Oct 24, 2024 •

edited

Loading

Uh oh!

thomasten Oct 24, 2024

Uh oh!

3u13r Oct 24, 2024 •

edited

Loading

Uh oh!

3u13r Oct 24, 2024

Uh oh!

thomasten Oct 24, 2024

Uh oh!

github-actions bot commented Oct 24, 2024

Uh oh!

thomasten left a comment

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

4 participants

Comments

Conversation

3u13r commented Oct 24, 2024

Context

Proposed change(s)

Checklist

Uh oh!

netlify bot commented Oct 24, 2024 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

✅ Deploy Preview for constellation-docs canceled.

Uh oh!

thomasten Oct 24, 2024

Choose a reason for hiding this comment

Uh oh!

3u13r Oct 24, 2024 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

3u13r Oct 24, 2024

Choose a reason for hiding this comment

Uh oh!

thomasten Oct 24, 2024

Choose a reason for hiding this comment

Uh oh!

github-actions bot commented Oct 24, 2024

Coverage report

Uh oh!

thomasten left a comment

Choose a reason for hiding this comment

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

4 participants

netlify bot commented Oct 24, 2024 •

edited

Loading

3u13r Oct 24, 2024 •

edited

Loading